
<h1><join>Profiling LISP Code</join></h1>
<p>WIKIPEDIA offers the
<a href="http://en.wikipedia.org/wiki/Optimization_(computer_science)">
following comments about optimizing
code</a>:
<ul>
  <p>
    "We should forget about small efficiencies,
  say about 97% of the time: premature optimization is the root of
  all evil." (Knuth, Donald. Structured Programming with go to Statements, ACM Journal Computing Surveys, Vol 6, No. 4, Dec. 1974. p.268.)

<p>"Premature optimization" is a phrase used to describe a situation where a programmer lets performance considerations affect the design of a piece of code. This can result in a design that is not as clean as it could have been or code that is incorrect, because the code is complicated by the optimization and the programmer is distracted by optimizing.

<p>An alternative approach is to design first, code from the design and then profile/benchmark the resulting code to see which parts should be optimized. A simple and elegant design is often easier to optimize at this stage, and profiling may reveal unexpected performance problems that would not have been addressed by premature optimization.
<p>To profile your code in SBCL LISP, you must first seperate your
  code from LISP's builtins:
  <pre>(defun my-funs ()
  (let ((out '()))
    (do-symbols  (s)
      (if (and (fboundp s)
               (find-symbol  (format nil "~a" s) *package*)
               (not (member s lisp-funs)))
          (push s out)))
    out))</pre>
<p>This code presumes that there is some large list of LISP
  functions predefined somewhere in <t>*lisp-funs*</t>. Such
  a list can be found in
  <p>Anyway, now we we can turn on SBCL's profiler, just on the
  functions in your code:<pre>
(defmacro watch (code)
  `(progn
    (sb-profile:unprofile)
    (sb-profile:reset)
    (sb-profile:profile ,@(my-funs))
    (eval ,code)
    (sb-profile:report)
    (sb-profile:unprofile)
    t)
)</pre>
<p>With all the above, then we can profile all the functions called from some high-level
  <t>(main)</t> function, as follows:<pre>
(watch (main))</pre>
<p>The result is a standard SBCL profiler output. Note that, in the following, the "!" function takes 0.447/0.707 (i.e. over half) the run time. So if we are going to optimize anything,
optimize "!".<pre>
CL-USER> (watch (main))
  seconds  |   consed   |   calls   |  sec/call  |  name  
------------------------------------------------------------
     0.447 |          0 |   990,001 |  0.0000005 | !
     0.105 |  6,819,840 |   170,000 |   0.000001 | EM2EFFORT
     0.073 |  6,795,264 |   170,000 |  0.0000004 | EM2RIN
     0.027 |  6,778,880 |   170,000 |  0.0000002 | EM2CIN
     0.020 |  1,585,152 |    50,000 |  0.0000004 | SF2CIN
     0.016 |  1,630,208 |    50,000 |  0.0000003 | SF2DIN
     0.012 |  6,742,016 |   170,000 |  0.0000001 | EM2DIN
     0.006 |    946,176 |    30,000 |  0.0000002 | DR2ROUT
     0.001 |          0 |        14 |   0.000067 | MAKE-R15
     0.001 |      8,192 |         1 |   0.000539 | COCOMO-DEFAULTS
     0.000 |          0 |         5 |   0.000000 | MAKE-SFS
     0.000 |          0 |         1 |   0.000000 | LINE-Y
     0.000 |          0 |        27 |   0.000000 | ?
     0.000 |          0 |         1 |   0.000000 | INIT-DB
     0.000 |          0 |         5 |   0.000000 | MAKE-R16
     0.000 |          0 |         7 |   0.000000 | MAKE-RIN+
     0.000 |  1,695,744 |    50,000 |   0.000000 | SF2EFFORT
     0.000 |          0 |         1 |   0.000000 | MAKE-R26
     0.000 |          0 |         9 |   0.000000 | MAKE-EM-
     0.000 |          0 |         6 |   0.000000 | MAKE-DIN+
     0.000 |          0 |         1 |   0.000000 | ?ONE-B
     0.000 |          0 |         1 |   0.000000 | MAKE-ONE-A
     0.000 |          0 |        27 |   0.000000 | GUESS
     0.000 |          0 |        25 |   0.000000 | ?ELT
     0.000 |          0 |         5 |   0.000000 | MAKE-DSF
     0.000 |    974,848 |    30,000 |   0.000000 | DR2DOUT
     0.000 |          0 |        34 |   0.000000 | MAKE-EM
     0.000 |          0 |        25 |   0.000000 | ?BAG
     0.000 |          0 |         6 |   0.000000 | MAKE-DR
     0.000 |          0 |        10 |   0.000000 | MAKE-RIN-
     0.000 |          0 |         5 |   0.000000 | MAKE-RSF
     0.000 |          0 |         3 |   0.000000 | ?DR
     0.000 |          0 |         1 |   0.000000 | POINT-TO-LINE
     0.000 |          0 |         3 |   0.000000 | MAKE-RDR
     0.000 |          0 |         1 |   0.000000 | DEMO456
     0.000 |          0 |         1 |   0.000000 | MAKE-LINE
     0.000 |          0 |         3 |   0.000000 | MAKE-R25
     0.000 |          0 |         3 |   0.000000 | MAKE-DDR
     0.000 |          0 |         5 |   0.000000 | MAKE-CSF
     0.000 |          0 |        10 |   0.000000 | MAKE-SF
     0.000 |          0 |         6 |   0.000000 | MAKE-CIN+
     0.000 |          0 |        11 |   0.000000 | MAKE-CIN-
     0.000 |          0 |        28 |   0.000000 | GETA
     0.000 |  1,482,752 |    50,000 |   0.000000 | SF2RIN
     0.000 |          0 |         5 |   0.000000 | ?SF
     0.000 |      8,192 |        17 |   0.000000 | ?EM
     0.000 |          0 |         8 |   0.000000 | MAKE-EM+
     0.000 |          0 |         2 |   0.000000 | MAKE-NUM
     0.000 |          0 |         1 |   0.000000 | ?ONE-A
     0.000 |    958,464 |    30,000 |   0.000000 | DR2COUT
     0.000 |          0 |         3 |   0.000000 | MAKE-CODR
     0.000 |          0 |         1 |   0.000000 | MAKE-ONE-B
     0.000 | 24,076,288 |         1 |   0.000000 | DEMO456A
     0.000 |          0 |        25 |   0.000000 | COCO
     0.000 |          0 |         2 |   0.000000 | MAKE-R36
     0.000 |          0 |        11 |   0.000000 | MAKE-DIN-
     0.000 |          0 |         1 |   0.000000 | MAKE-DB
     0.000 |    155,648 |    10,124 |   0.000000 | MY-RANDOM
------------------------------------------------------------
     0.707 | 60,657,664 | 1,970,493 |            | Total
